[Timers] Add a flag to set a minimum timer value for printing #139306
Conversation
The new LLVM flag `-min-print-time` is the number of seconds a timer must have in order for its value to be printed in either JSON or human readable formatting. This may be used, for example, with Clang's `-ftime-report` to reduce its output size by not printing insignificant values. The default value of this flag is 0 which retains the current behavior of printing all timer values.
|
@llvm/pr-subscribers-llvm-support Author: Alan Zhao (alanzhao1) ChangesThe new LLVM flag The default value of this flag is 0 which retains the current behavior of printing all timer values. Full diff: https://github.com/llvm/llvm-project/pull/139306.diff 2 Files Affected:
diff --git a/llvm/lib/Support/Timer.cpp b/llvm/lib/Support/Timer.cpp
index 22811d7b4af0a..9cc22fbb8bc38 100644
--- a/llvm/lib/Support/Timer.cpp
+++ b/llvm/lib/Support/Timer.cpp
@@ -53,6 +53,7 @@ class Name2PairMap;
static std::string &libSupportInfoOutputFilename();
static bool trackSpace();
static bool sortTimers();
+cl::opt<unsigned> &minPrintTime();
[[maybe_unused]]
static SignpostEmitter &signposts();
static sys::SmartMutex<true> &timerLock();
@@ -380,8 +381,12 @@ void TimerGroup::PrintQueuedTimers(raw_ostream &OS) {
// Loop through all of the timing data, printing it out.
for (const PrintRecord &Record : llvm::reverse(TimersToPrint)) {
- Record.Time.print(Total, OS);
- OS << Record.Description << '\n';
+ if (const TimeRecord &TR = Record.Time; TR.getUserTime() >= minPrintTime() ||
+ TR.getSystemTime() >= minPrintTime() ||
+ TR.getWallTime() >= minPrintTime()) {
+ Record.Time.print(Total, OS);
+ OS << Record.Description << '\n';
+ }
}
Total.print(Total, OS);
@@ -452,22 +457,31 @@ const char *TimerGroup::printJSONValues(raw_ostream &OS, const char *delim) {
prepareToPrintList(false);
for (const PrintRecord &R : TimersToPrint) {
- OS << delim;
- delim = ",\n";
-
const TimeRecord &T = R.Time;
- printJSONValue(OS, R, ".wall", T.getWallTime());
- OS << delim;
- printJSONValue(OS, R, ".user", T.getUserTime());
- OS << delim;
- printJSONValue(OS, R, ".sys", T.getSystemTime());
+ if (double Value = T.getWallTime(); Value >= minPrintTime()) {
+ OS << delim;
+ printJSONValue(OS, R, ".wall", Value);
+ delim = ",\n";
+ }
+ if (double Value = T.getWallTime(); Value >= minPrintTime()) {
+ OS << delim;
+ printJSONValue(OS, R, ".user", T.getUserTime());
+ delim = ",\n";
+ }
+ if (double Value = T.getWallTime(); Value >= minPrintTime()) {
+ OS << delim;
+ printJSONValue(OS, R, ".sys", T.getSystemTime());
+ delim = ",\n";
+ }
if (T.getMemUsed()) {
OS << delim;
printJSONValue(OS, R, ".mem", T.getMemUsed());
+ delim = ",\n";
}
if (T.getInstructionsExecuted()) {
OS << delim;
printJSONValue(OS, R, ".instr", T.getInstructionsExecuted());
+ delim = ",\n";
}
}
TimersToPrint.clear();
@@ -515,6 +529,9 @@ class llvm::TimerGlobals {
cl::desc("In the report, sort the timers in each group in wall clock"
" time order"),
cl::init(true), cl::Hidden};
+ cl::opt<unsigned> MinPrintTime{
+ "min-print-time",
+ cl::desc("Minimum time in seconds for a timer to be printed"), cl::init(0)};
sys::SmartMutex<true> TimerLock;
TimerGroup DefaultTimerGroup{"misc", "Miscellaneous Ungrouped Timers",
@@ -541,6 +558,7 @@ static std::string &libSupportInfoOutputFilename() {
}
static bool trackSpace() { return ManagedTimerGlobals->TrackSpace; }
static bool sortTimers() { return ManagedTimerGlobals->SortTimers; }
+cl::opt<unsigned> &minPrintTime() { return ManagedTimerGlobals->MinPrintTime; }
static SignpostEmitter &signposts() { return ManagedTimerGlobals->Signposts; }
static sys::SmartMutex<true> &timerLock() {
return ManagedTimerGlobals->TimerLock;
diff --git a/llvm/unittests/Support/TimerTest.cpp b/llvm/unittests/Support/TimerTest.cpp
index 612fd7231da70..0eb81f07bed5a 100644
--- a/llvm/unittests/Support/TimerTest.cpp
+++ b/llvm/unittests/Support/TimerTest.cpp
@@ -7,6 +7,8 @@
//===----------------------------------------------------------------------===//
#include "llvm/Support/Timer.h"
+#include "llvm/Support/CommandLine.h"
+#include "gmock/gmock.h"
#include "gtest/gtest.h"
#if _WIN32
@@ -17,18 +19,20 @@
using namespace llvm;
+cl::opt<unsigned> &minPrintTime();
+
namespace {
// FIXME: Put this somewhere in Support, it's also used in LockFileManager.
-void SleepMS() {
+void SleepMS(int ms = 1) {
#if _WIN32
- Sleep(1);
+ Sleep(ms);
#else
struct timespec Interval;
- Interval.tv_sec = 0;
- Interval.tv_nsec = 1000000;
+ Interval.tv_sec = ms / 1000;
+ Interval.tv_nsec = 1000000 * (ms % 1000);
#if defined(__MVS__)
- long Microseconds = (Interval.tv_nsec + 999) / 1000;
+ long Microseconds = (Interval.tv_nsec + Interval.tv_sec * 1000 + 999) / 1000;
usleep(Microseconds);
#else
nanosleep(&Interval, nullptr);
@@ -82,4 +86,34 @@ TEST(Timer, TimerGroupTimerDestructed) {
EXPECT_FALSE(testing::internal::GetCapturedStderr().empty());
}
+TEST(Timer, MinTimerFlag) {
+ testing::internal::CaptureStderr();
+
+ Timer T1("T1", "T1");
+ Timer T2("T2", "T2");
+
+ minPrintTime().setValue(2);
+
+ T1.startTimer();
+ T2.startTimer();
+
+ SleepMS(1000);
+ T1.stopTimer();
+
+ SleepMS(2000);
+ T2.stopTimer();
+
+ TimerGroup::printAll(llvm::errs());
+ std::string stderr = testing::internal::GetCapturedStderr();
+ EXPECT_THAT(stderr, testing::HasSubstr("T2"));
+ EXPECT_THAT(stderr, testing::Not(testing::HasSubstr("T1")));
+
+ testing::internal::CaptureStderr();
+
+ TimerGroup::printAllJSONValues(llvm::errs(), "");
+ stderr = testing::internal::GetCapturedStderr();
+ EXPECT_THAT(stderr, testing::HasSubstr("T2.wall"));
+ EXPECT_THAT(stderr, testing::Not(testing::HasSubstr("T1.wall")));
+}
+
} // namespace
|
|
✅ With the latest revision this PR passed the C/C++ code formatter. |
zmodem
left a comment
zmodem
left a comment
There was a problem hiding this comment.
This seems to duplicate the logic between PrintQueuedTimers and printJSONValues. Maybe the filtering could happen in prepareToPrintList instead?
But more generally, is this the most useful way of limiting the output size? It seems the output size with a certain timer cutoff could vary a lot depending on how long the compilation ran for example. Maybe a flag to only print the top-N timers would be more useful?
This seems like something that requires more discussion; I created a thread on Discourse: https://discourse.llvm.org/t/timers-ideas-for-truncating-the-output-of-ftime-report-and-ftime-report-json/86723 |
| Record.Time.print(Total, OS); | ||
| OS << Record.Description << '\n'; | ||
| if (const TimeRecord &TR = Record.Time; | ||
| TR.getUserTime() > minPrintTime() || |
There was a problem hiding this comment.
could we call minPrintTime only once here (i.e. factoring out this function call)? It's unlikely that compiler would CSE these calls since minPrintTime is accessing a ManagedStatic.
|
|
||
| #include "llvm/Support/Timer.h" | ||
| #include "llvm/Support/CommandLine.h" | ||
| #include "gmock/gmock.h" |
There was a problem hiding this comment.
is there any reason you need gmock.h here?
5 participants
The new LLVM flag
-timer-min-print-timeis the number of seconds a timer must have in order for its value to be printed in either JSON or human readable formatting. This may be used, for example, with Clang's-ftime-reportto reduce its output size by not printing insignificant values.The default value of this flag is 0 which retains the current behavior of printing all timer values.